Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Span parenting so that system spans are correctly linked in multithreaded executor #2423

Closed
wants to merge 2 commits into from
Closed

Span parenting so that system spans are correctly linked in multithreaded executor #2423

wants to merge 2 commits into from

Conversation

mockersf
Copy link
Member

@mockersf mockersf commented Jul 1, 2021

Objective

When using a parallel executor, system spans are not correctly related to the stage/frame spans

Example logs:

Jul 01 18:39:40.772  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.853  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.866  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.881  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.907  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.928  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.972  INFO bevy_app:frame:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.997  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.027  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.064  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.092  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.108  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.140  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.176  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.208  INFO bevy_app:frame:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.237  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.258  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.288  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light

Logs with bevy_app:frame... are when the system is executed on the main thread, the other lines are on other threads

Solution

Correctly pass the parent span, and set it as parent when creating a new one. I also added the frame count to the frame span as this was how this issue was noticed on discord

Jul 01 19:05:46.288  INFO bevy_app:frame{frame_count=1}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.390  INFO bevy_app:frame{frame_count=2}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.400  INFO bevy_app:frame{frame_count=3}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.426  INFO bevy_app:frame{frame_count=4}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.460  INFO bevy_app:frame{frame_count=5}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.501  INFO bevy_app:frame{frame_count=6}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.524  INFO bevy_app:frame{frame_count=7}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.564  INFO bevy_app:frame{frame_count=8}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.596  INFO bevy_app:frame{frame_count=9}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.626  INFO bevy_app:frame{frame_count=10}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.657  INFO bevy_app:frame{frame_count=11}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.690  INFO bevy_app:frame{frame_count=12}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.725  INFO bevy_app:frame{frame_count=13}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.758  INFO bevy_app:frame{frame_count=14}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.791  INFO bevy_app:frame{frame_count=15}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.825  INFO bevy_app:frame{frame_count=16}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.858  INFO bevy_app:frame{frame_count=17}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.892  INFO bevy_app:frame{frame_count=18}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.923  INFO bevy_app:frame{frame_count=19}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.958  INFO bevy_app:frame{frame_count=20}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light

@github-actions github-actions bot added the S-Needs-Triage This issue needs to be labelled label Jul 1, 2021
@mockersf mockersf force-pushed the span-parenting branch 2 times, most recently from a599c9f to dd90337 Compare July 1, 2021 17:16
DJMcNab
DJMcNab approved these changes Jul 7, 2021
View reviewed changes
crates/bevy_ecs/src/schedule/executor_parallel.rs
} else {
bevy_utils::tracing::info_span!("system", name = &*system.name())
}
};
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As far as I can see this is an exact copy of the SingleThreadedExecutor's code to calculate this - it might be worth factoring it out?

@DJMcNab DJMcNab added C-Usability A simple quality-of-life change that makes Bevy easier to use and removed S-Needs-Triage This issue needs to be labelled labels Jul 7, 2021
@cart cart added the S-Pre-Relicense This PR was made before Bevy added the Apache license. Cannot be merged or used for other work label Jul 23, 2021
@mockersf mockersf removed the S-Pre-Relicense This PR was made before Bevy added the Apache license. Cannot be merged or used for other work label Jul 24, 2021
@mockersf mockersf mentioned this pull request Oct 2, 2021
Closed
@CAD97
Copy link
Contributor

CAD97 commented Oct 2, 2021

I didn't find this when I was looking, so I also made #2905 to fix this same instance of the span parent chain breaking. #2905 accomplishes this in a simpler fashion, as it manages to continue to use tracing's implicit TLS scoping (by hoisting span creation outside of the task onto the main thread) rather than adding a new channel to pass the span parent down.

@mockersf
Copy link
Member Author

mockersf commented Oct 6, 2021

closed for better fix in #2905

@mockersf mockersf closed this Oct 6, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@DJMcNab DJMcNab DJMcNab approved these changes

Assignees
No one assigned
Labels
C-Usability A simple quality-of-life change that makes Bevy easier to use
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
5 participants
@mockersf @CAD97 @DJMcNab @cart @alice-i-cecile